Managing Logs

  • lastlog
  • last, lastb
  • dmsg
  • syslog, logger, logrotate
  • journalctl

lastlog

In [29]:
lastlog -u milad
Username         Port     From             Latest
milad            tty1                      Tue Feb 28 13:57:38 +0330 2017
In [47]:
lastlog | tail -3
vnstat                                     **Never logged in**
raven                                      **Never logged in**
nm-openvpn                                 **Never logged in**
In [48]:
lastlog | grep -vi never
Username         Port     From             Latest
milad            tty1                      Tue Feb 28 13:57:38 +0330 2017

last, lastb

In [37]:
# last --help
last --since "5 min ago" -n 1
milad    pts/9        :0               Tue Feb 28 19:32 - 19:32  (00:00)

wtmp begins Wed Feb  1 20:14:48 2017
In [78]:
last | tail -6 | tac | tail -4
milad    pts/2        :0               Wed Feb  1 20:14 - 22:39  (02:24)
milad    pts/1        :0               Wed Feb  1 22:47 - 23:41  (00:54)
milad    pts/2        :0               Wed Feb  1 23:37 - 23:47  (00:10)
milad    pts/0        :0               Wed Feb  1 23:47 - 23:47  (00:00)
In [40]:
last reboot -n5
reboot   system boot  4.4.0-64-generic Tue Feb 28 13:57   still running
reboot   system boot  4.4.0-64-generic Mon Feb 27 12:14   still running
reboot   system boot  4.4.0-64-generic Sun Feb 26 22:31 - 02:23  (03:51)
reboot   system boot  4.4.0-64-generic Sat Feb 25 20:17 - 18:05  (21:48)
reboot   system boot  4.4.0-64-generic Sat Feb 25 09:38 - 18:05 (1+08:26)

wtmp begins Wed Feb  1 20:14:48 2017
In [ ]:
sudo lastb

milad tty1 Fri Feb 24 12:26 - 12:26 (00:00)

In [43]:
ls /var/log/*tmp -1
/var/log/btmp
/var/log/wtmp

dmesg

  • dmesg obtains its data by reading the kernel ring buffer.
  • buffer is a portion of a computer's memory that is set aside as a temporary holding place for data that is being sent to or received from an external device, such as a hard disk drive (HDD), printer or keyboard.
  • ring buffer is a buffer of fixed size for which any new data added to it overwrites the oldest data in it.
In [5]:
whatis dmesg
dmesg (1)            - print or control the kernel ring buffer
In [1]:
dmesg -l err -H # Level, Human readable
[Feb28 13:56] Error parsing PCC subspaces from PCCT
[Feb28 16:26] sd 6:0:0:0: [sdb] No Caching mode page found
[  +0.000004] sd 6:0:0:0: [sdb] Assuming drive cache: write through
In [7]:
cat /var/log/dmesg # Until system boot
(Nothing has been logged yet.)

SYSLOG, Logger, logrotate

In [22]:
pgrep syslog -a
1047 /usr/sbin/rsyslogd -n
In [43]:
# Lets see what syslog is

apt-cache show rsyslog | grep -i desc -A14 -m1 | cat
Description-en: reliable system and kernel logging daemon
 Rsyslog is a multi-threaded implementation of syslogd (a system utility
 providing support for message logging), with features that include:
  * reliable syslog over TCP, SSL/TLS and RELP
  * on-demand disk buffering
  * email alerting
  * writing to MySQL or PostgreSQL databases (via separate output plugins)
  * permitted sender lists
  * filtering on any part of the syslog message
  * on-the-wire message compression
  * fine-grained output format control
  * failover to backup destinations
  * enterprise-class encrypted syslog relaying
 .
 It is the default syslogd on Debian systems.
In [54]:
ls /var/log | egrep -v "gz|.1" | tr "\n" " "

apt auth.log btmp dmesg kern.log lastlog wtmp syslog

In [55]:
tail /var/log/auth.log | grep sudo | head -1
Feb 28 19:37:27 Raven sudo:    milad : TTY=pts/5 ; PWD=/etc ; USER=root ; COMMAND=/usr/bin/lastb
In [2]:
# lets see how rsyslog manages these files

# facilities  0.kern
# priority    0 emerg

# /identifier  sudo/

vim /etc/rsyslog.d/50-default.conf
In [71]:
logger -p mail.err "Milad is not able to send mail"
In [14]:
tail -1 /var/log/mail.err
Feb 28 19:58:06 Raven milad: Milad is not able to send mail
In [79]:
whatis logrotate
logrotate (8)        - rotates, compresses, and mails system logs
In [ ]:
logrotate /etc/logrotate.conf
In [ ]:
/var/log/test.log
{
        rotate 4
        weekly
        missingok
        notifempty
        compress
}

journalctl

When used alone, every journal entry that is in the system will be displayed.

  • Includes logs from:
    • the early boot process
    • the kernel
    • the initrd
    • applications stdout/stderr
In [6]:
whatis journalctl
journalctl (1)       - Query the systemd journal
In [17]:
# remember our mail message log? 
# logger -p mail.err "Milad is not able to send mail"
journalctl SYSLOG_FACILITY=2 -n1
-- Logs begin at Tue 2017-02-28 13:57:11 IRST, end at Wed 2017-03-01 00:45:01 IRST. --
Feb 28 19:58:06 Raven.localhost milad[13383]: Milad is not able to send mail
In [8]:
journalctl -n 3
-- Logs begin at Tue 2017-02-28 13:57:11 IRST, end at Tue 2017-02-28 19:00:27 IRST. --
Feb 28 19:00:27 Raven.localhost systemd[1446]: Time has been changed
Feb 28 19:00:27 Raven.localhost systemd[1]: Time has been changed
Feb 28 19:00:27 Raven.localhost systemd[1]: apt-daily.timer: Adding 10h 37min 30.380011s random time.
In [11]:
journalctl -n 2 -x # extra explaination (catalog)
-- Logs begin at Tue 2017-02-28 13:57:11 IRST, end at Tue 2017-02-28 19:00:27 IRST. --
Feb 28 19:00:27 Raven.localhost systemd[1]: Time has been changed
-- Subject: Time change
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- The system clock has been changed to REALTIME microseconds after January 1st, 1970.
Feb 28 19:00:27 Raven.localhost systemd[1]: apt-daily.timer: Adding 10h 37min 30.380011s random time.

Persistent Log

In [ ]:
# vim /etc/systemd/journald.conf

[Journal]
Storage=persistent
In [ ]:
man 5 journald.conf

/Storage
"volatile", "persistent", "auto"
"persistent", data will be stored preferably on disk

Filter by boot or time

In [7]:
journalctl --list-boots
 0 8dcd6ce7c4f141eb9c52dd88b71ac0d6 Tue 2017-02-28 13:57:11 IRST—Tue 2017-02-28 16:05:01 IRST
In [11]:
journalctl -b # Last boot
In [80]:
journalctl -b 8dcd6ce7c4f141eb9c52dd88b71ac0d6 -n1

# journalctl -b 0
-- Logs begin at Tue 2017-02-28 13:57:11 IRST, end at Tue 2017-02-28 21:45:01 IRST. --
Feb 28 21:45:01 Raven.localhost CRON[16610]: pam_unix(cron:session): session closed for user root
In [18]:
journalctl --since 16:02 --until 16:07
In [17]:
journalctl --since "2017-02-28 16:05"

Available words: "yesterday", "today", "tomorrow", or "now"

In [ ]:
journalctl --since yesterday
In [ ]:
journalctl --since 01:00 --until "5 hour ago"

Filter by units

In [88]:
journalctl -u virtualbox.service -n1
-- Logs begin at Tue 2017-02-28 13:57:11 IRST, end at Tue 2017-02-28 21:45:01 IRST. --
Feb 28 13:57:32 Raven.localhost systemd[1]: Started LSB: VirtualBox Linux kernel module.
In [89]:
journalctl _SYSTEMD_UNIT=virtualbox.service --no-full -n1
-- Logs begin at Tue 2017-02-28 13:57:11 IRST, end at Tue 2017-02-28 21:45:01 IRST. --
Feb 28 13:57:32 Raven.localhost virtualbox[1259]:    ...done.
In [18]:
systemctl status dbus
 dbus.service - D-Bus System Message Bus
   Loaded: loaded (/lib/systemd/system/dbus.service; static; vendor preset: enabled)
   Active: active (running) since Tue 2017-02-28 13:57:22 IRST; 10h ago
     Docs: man:dbus-daemon(1)
 Main PID: 1051 (dbus-daemon)
   CGroup: /system.slice/dbus.service
           └─1051 /usr/bin/dbus-daemon --system --address=systemd: --nofork -...

Feb 28 15:47:05 Raven.localhost dbus[1051]: [system] Activating via systemd:...'
Feb 28 15:47:05 Raven.localhost dbus[1051]: [system] Successfully activated ...'
Feb 28 15:52:51 Raven.localhost dbus[1051]: [system] Activating via systemd:...'
Feb 28 15:52:52 Raven.localhost dbus[1051]: [system] Successfully activated ...'
Feb 28 15:54:16 Raven.localhost dbus[1051]: [system] Activating via systemd:...'
Feb 28 15:54:16 Raven.localhost dbus[1051]: [system] Successfully activated ...'
Feb 28 18:16:30 Raven.localhost dbus[1051]: [system] Activating via systemd:...'
Feb 28 18:16:31 Raven.localhost dbus[1051]: [system] Successfully activated ...'
Feb 28 20:50:11 Raven.localhost dbus[1051]: [system] Activating via systemd:...'
Feb 28 20:50:11 Raven.localhost dbus[1051]: [system] Successfully activated ...'
Hint: Some lines were ellipsized, use -l to show in full.
In [19]:
journalctl -u dbus -n --no-full
-- Logs begin at Tue 2017-02-28 13:57:11 IRST, end at Wed 2017-03-01 00:55:01 IRST. --
Feb 28 15:47:05 Raven.localhost dbus[1051]: [system] Activating via systemd:...'
Feb 28 15:47:05 Raven.localhost dbus[1051]: [system] Successfully activated ...'
Feb 28 15:52:51 Raven.localhost dbus[1051]: [system] Activating via systemd:...'
Feb 28 15:52:52 Raven.localhost dbus[1051]: [system] Successfully activated ...'
Feb 28 15:54:16 Raven.localhost dbus[1051]: [system] Activating via systemd:...'
Feb 28 15:54:16 Raven.localhost dbus[1051]: [system] Successfully activated ...'
Feb 28 18:16:30 Raven.localhost dbus[1051]: [system] Activating via systemd:...'
Feb 28 18:16:31 Raven.localhost dbus[1051]: [system] Successfully activated ...'
Feb 28 20:50:11 Raven.localhost dbus[1051]: [system] Activating via systemd:...'
Feb 28 20:50:11 Raven.localhost dbus[1051]: [system] Successfully activated ...'
In [24]:
journalctl -u dbus.service --since yesterday -n3 -b0
Feb 28 13:57:22 Raven.localhost systemd[1]: Started D-Bus System Message Bus.
Feb 28 13:57:22 Raven.localhost dbus-daemon[1051]: Unknown username "whoopsie" in message bus configuration file
Feb 28 13:57:22 Raven.localhost dbus[1051]: [system] AppArmor D-Bus mediation is enabled
In [42]:
journalctl -t dbus -n3 --no-full # syslog identifier (look at systemd message at above example)
-- Logs begin at Tue 2017-02-28 13:57:11 IRST, end at Wed 2017-03-01 01:05:01 IRST. --
Feb 28 18:16:31 Raven.localhost dbus[1051]: [system] Successfully activated ...'
Feb 28 20:50:11 Raven.localhost dbus[1051]: [system] Activating via systemd:...'
Feb 28 20:50:11 Raven.localhost dbus[1051]: [system] Successfully activated ...'

Filter by fileds

man systemd.journal-fields

In [33]:
journalctl -N | grep "^_" | tail -10
_AUDIT_TYPE
_UDEV_DEVNODE
_HOSTNAME
_GID
_UID
_SYSTEMD_UNIT
_AUDIT_FIELD_PROFILE
_BOOT_ID
_SYSTEMD_OWNER_UID
_AUDIT_FIELD_OPERATION
In [26]:
journalctl _UID=`id -u privoxy`
-- No entries --

Available values for a given journal field:

In [40]:
journalctl -F _TRANSPORT
# transport = How the entry was received by the journal service.
audit
syslog
stdout
journal
kernel
driver
In [32]:
journalctl _TRANSPORT=kernel | head -3 | tail -2
Feb 28 13:57:11 Raven.localhost kernel: Initializing cgroup subsys cpuset
Feb 28 13:57:11 Raven.localhost kernel: Initializing cgroup subsys cpu
In [30]:
journalctl -F SYSLOG_IDENTIFIER -n10
ntfs-3g
milad
upowerd
org.gtk.vfs.Daemon
CRON
org.gtk.vfs.AfcVolumeMonitor
udisksd
systemd-timesyncd
sudo
dnsmasq
In [39]:
journalctl -t smartd -r -n1
-- Logs begin at Tue 2017-02-28 13:57:11 IRST, end at Wed 2017-03-01 01:05:01 IRST. --
Feb 28 23:57:24 Raven.localhost smartd[1036]: Device: /dev/sda [SAT], SMART Usage Attribute: 194 Temperature_Celsius changed from 43 to 44

SYSLOG Facilities

  • syslog facilities:
    • 0 kernel messages
    • 1 user-level messages
    • 2 mail system
    • 3 system daemons
    • 4 security/authorization messages
    • 5 messages generated internally by syslogd
    • 6 line printer subsystem
    • 7 network news subsystem
    • 8 UUCP subsystem
    • 9 clock daemon
    • 10 security/authorization messages
    • 11 FTP daemon
    • 12 NTP subsystem
In [1]:
journalctl -N | grep -i fac
SYSLOG_FACILITY
In [3]:
journalctl -F SYSLOG_FACILITY | tr '\n' ' '
2 10 AUDIT SUPPLICANT MB GLIB DEVICE WIFI PLATFORM DHCP6 DHCP4 SETTINGS RFKILL DNS CORE 9 4 1 0 3 

Kernel logs

kernel ring buffer (dmesg)

In [35]:
journalctl -k | wc -l
journalctl --dmesg | wc -l
dmesg | wc -l
900
900
900
In [36]:
journalctl -k -b -3
Specifying boot ID has no effect, no persistent journal was found
In [9]:
journalctl SYSLOG_FACILITY=0 -n2
-- Logs begin at Tue 2017-02-28 13:57:11 IRST, end at Wed 2017-03-01 00:35:01 IRST. --
Feb 28 16:26:18 Raven.localhost kernel: sd 6:0:0:0: [sdb] Attached SCSI disk
Feb 28 21:19:20 Raven.localhost kernel: usb 4-5: reset SuperSpeed USB device number 2 using xhci_hcd

Logs generated by a binary

In [55]:
journalctl `which NetworkManager` -n1
-- Logs begin at Tue 2017-02-28 13:57:11 IRST, end at Tue 2017-02-28 17:21:43 IRST. --
Feb 28 13:58:09 Raven.localhost NetworkManager[1057]: <info>  [1488277689.6789] dnsmasq[0x149e7a0]: dnsmasq appeared as :1.22
In [39]:
journalctl -u NetworkManager.service | wc -l
journalctl `which NetworkManager` | wc -l
123
112

Priority

journalctl -p [tab][tab]

0: emerg : System is unusable 
1: alert :  Should be corrected immediately 
2: crit :  Critical conditions 
3: err :  Error conditions 
4: warning :  May indicate that an error will occur if action is not taken. 
5: notice :  Events that are unusual, but not error conditions. 
6: info :  Normal operational messages that require no action. 
7: debug :  Information useful to developers for debugging the application. 
In [5]:
journalctl -p 1 -n1 # -p emerg
-- Logs begin at Tue 2017-02-28 13:57:11 IRST, end at Wed 2017-03-01 00:25:01 IRST. --
Feb 28 21:58:04 Raven.localhost sudo[16702]:    milad : 3 incorrect password attempts ; TTY=pts/3 ; PWD=/home/milad ; USER=root ; COMMAND=/bin/ls
In [ ]:
journalctl -p crit -o json-pretty # [tab-tab]
In [ ]:
journalctl -k -f # following like tail -f

Old logs

In [94]:
journalctl --disk-usage
sudo journalctl --vacuum-size=5M
sudo journalctl --vacuum-time=2months
Archived and active journals take up 4.5M on disk.
In [ ]:
Referenses:

LFCS & RHCSA

man dmsg
man journalctl
man 5 journald.conf
man systemd.journal-fields

http://www.linfo.org/dmesg.html
https://wiki.archlinux.org/index.php/Systemd
https://help.ubuntu.com/community/LinuxLogFiles
https://tools.ietf.org/html/rfc5424#section-6.2.1
https://www.digitalocean.com/community/tutorials/how-to-use-journalctl-to-view-and-manipulate-systemd-logs

Lecture notes

License

Creative Commons License

Linux Notes by Milad As (Ravexina) is licensed under a Creative Commons Attribution-NonCommercial-ShareAlike 4.0 International License.


ravexina's gitlab

ravexina's github